Performance-Problem, mal wieder

Moin,

so, ich bin mit meinem Latein am Ende:

Im Log fand ich:

> LOG: duration: 1021.310 ms statement: delete from t_eingeloggt where=
personid =3D 148


So, nun mit psql und einem Explain analyse:

> explain analyse delete from t_eingeloggt where personid =3D 148;
> QUERY PLAN
> ------------------------------------------------------------ -----------=
-------------------------------------
> Delete (cost=3D0.00..4.39 rows=3D1 width=3D6) (actual time=3D0.069..0=
..069 rows=3D0 loops=3D1)
> -> Seq Scan on t_eingeloggt (cost=3D0.00..4.39 rows=3D1 width=3D6)=
(actual time=3D0.066..0.066 rows=3D0 loops=3D1)
> Filter: (personid =3D 148)
> Total runtime: 0.091 ms
> (4 rows)

(Tabelle enthält aktuell 192 records, besteht aus (int,
varchar(200),int) und hat einen Index auf personid.


Das ist ein Seq-Scan im Explain, der 0.1 ms braucht. Im Log taucht das
mit 10.000 facher Laufzeit auf. Der Server langweilt sich, da ist fast
keine LOAD, er hat 16 kerne und 24 GByte RAM. Storage via iSCSI, der
komplette DB-Cluster dürfte aber komplett im Shared-mem liegen.

Es lief kein Checkpoint bei der ersten Abfrage, der kam erst 2 Minuten
später und schrieb 1 Block.

Das ist kein Einzelfall, da sind etliche solcher unverständlichen
Laufzeiten im Log.


Sachdienliche Hinweise bitte an mich ...


Andreas
--=20
Andreas Kretschmer
http://internet24.de

--=20
Sent via pgsql-de-allgemein mailing list (pgsql-de-allgemein@postgresql.o=
rg)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-de-allgemein

Re: Performance-Problem, mal wieder

moin andreas,

LOG: duration: 1021.310 ms statement: delete from t_eingeloggt where personid = 148

> .....
> Sachdienliche Hinweise bitte an mich ...
>
>
> Andreas

also ein problem ist es nicht, sowas zu provozieren:

2011-01-06 08:03:46 CET pgfakt pgfakt 4011 LOG: statement: delete from
pgf_log where oid=1635437;
2011-01-06 08:03:46 CET pgfakt pgfakt 4011 LOG: duration: 0.716 ms
2011-01-06 08:04:00 CET 4014 DEBUG: autovacuum: processing database "pgfakt"
2011-01-06 08:04:00 CET 3990 DEBUG: server process (PID 4014) exited with
exit code 0
2011-01-06 08:04:03 CET pgfakt pgfakt 4011 LOG: statement: delete from
pgf_log where oid=18885;
2011-01-06 08:04:03 CET pgfakt pgfakt 4011 LOG: duration: 0.716 ms
2011-01-06 08:04:17 CET pgfakt pgfakt 4006 LOG: statement: delete from
pgf_log where oid= 18885 ;
......
2011-01-06 08:05:56 CET pgfakt pgfakt 4006 LOG: duration: 99249.447 ms <-----!!


was in diesem log fehlt, ist dieses stueck:

2011-01-06 08:03:31 CET pgfakt pgfakt 4011 LOG: statement: begin;
2011-01-06 08:03:31 CET pgfakt pgfakt 4011 LOG: duration: 0.214 ms
.....
2011-01-06 08:05:00 CET 4059 DEBUG: autovacuum: processing database "pgfakt"
2011-01-06 08:05:00 CET 3990 DEBUG: server process (PID 4059) exited with
exit code 0
2011-01-06 08:05:18 CET 3990 DEBUG: forked new backend, pid=4065 socket=8
2011-01-06 08:05:18 CET [unknown] [unknown] 4065 LOG: connection received:
host=xxxxx port=35873
2011-01-06 08:05:18 CET pgfakt pgfakt 4065 LOG: connection authorized:
user=pgfakt database=pgfakt
2011-01-06 08:05:33 CET pgfakt pgfakt 4065 LOG: statement: select count (oid)
from pgf_log;
2011-01-06 08:05:34 CET pgfakt pgfakt 4065 LOG: duration: 71.589 ms
2011-01-06 08:05:56 CET pgfakt pgfakt 4011 LOG: statement: rollback;
2011-01-06 08:05:56 CET pgfakt pgfakt 4011 LOG: duration: 0.294 ms



bist du sicher, das da nicht irgendwo ein

4006 ? Ss 0:00 postgres: pgfakt pgfakt xxxxx(35871) DELETE waiting
on a lock

rumduempelt?


viele gruesse

ralf


------------------------------------------------------------ -----
Ralf Burger AG
Roenskenstr. 37
46562 Voerde


HRB: AG Duisburg HRB 18758
USt.-ID: DE151403601
Vorstand: Ralf Burger
Vorsitzende des Aufsichtsrates: Andrea Giebel

Telefon und Internet
====================
Festnetz: 02855 / 26 18
0700 123 456 00 (12ct/min)

Internet: http://www.burger-ag.de/


--
Sent via pgsql-de-allgemein mailing list (pgsql-de-allgemein@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-de-allgemein

Re: Performance-Problem, mal wieder

This is a multi-part message in MIME format.
--------------050905040701020407050402
Content-Type: text/plain; charset=ISO-8859-15; format=flowed
Content-Transfer-Encoding: quoted-printable

Hi,

das das explain analyze schnell ist und die echte aktion nicht spricht=20
für Probleme im Storage. Bei der Datenmenge und dem System kann man CPU=
=20
getrost ignorieren. Schau doch mal nach Netzwerkproblemen. Ich würd ein=
=20
Monitoring des Durchsatzes bei anhaltendem IO Durchsatz machen.

Gruss
Thomas

Am 06.01.2011 06:40, schrieb Andreas Kretschmer:
> Moin,
>
> so, ich bin mit meinem Latein am Ende:
>
> Im Log fand ich:
>
>> LOG: duration: 1021.310 ms statement: delete from t_eingeloggt whe=
re personid =3D 148
>
> So, nun mit psql und einem Explain analyse:
>
>> explain analyse delete from t_eingeloggt where personid =3D 148;
>> QUERY PLAN
>> ------------------------------------------------------------ ----------=
--------------------------------------
>> Delete (cost=3D0.00..4.39 rows=3D1 width=3D6) (actual time=3D0.069.=
..0.069 rows=3D0 loops=3D1)
>> -> Seq Scan on t_eingeloggt (cost=3D0.00..4.39 rows=3D1 width=3D=
6) (actual time=3D0.066..0.066 rows=3D0 loops=3D1)
>> Filter: (personid =3D 148)
>> Total runtime: 0.091 ms
>> (4 rows)
> (Tabelle enthält aktuell 192 records, besteht aus (int,
> varchar(200),int) und hat einen Index auf personid.
>
>
> Das ist ein Seq-Scan im Explain, der 0.1 ms braucht. Im Log taucht das
> mit 10.000 facher Laufzeit auf. Der Server langweilt sich, da ist fast
> keine LOAD, er hat 16 kerne und 24 GByte RAM. Storage via iSCSI, der
> komplette DB-Cluster dürfte aber komplett im Shared-mem liegen.
>
> Es lief kein Checkpoint bei der ersten Abfrage, der kam erst 2 Minuten
> später und schrieb 1 Block.
>
> Das ist kein Einzelfall, da sind etliche solcher unverständlichen
> Laufzeiten im Log.
>
>
> Sachdienliche Hinweise bitte an mich ...
>
>
> Andreas

--=20

Thomas Markus

==================== =====3D=
==================== =====3D=
==
proventis GmbH | Zimmerstr. 79-81 | D-10117 Berlin |
Tel +49 (0)30 2936399-22 | Fax -50 | t.markus@proventis.net
------------------------------------------------------------ -----
Geschäftsführer: Norman Frischmuth | Sitz: Berlin
Handelsregister: AG Berlin-Charlottenburg, HR 82917
------------------------------------------------------------ -----
Blue Ant-webbasiertes Projektmanagement - aktuelle Termine:
http://www.proventis.net/website/live/blueant/veranstaltunge n.html
==================== =====3D=
==================== =====3D=
==


--------------050905040701020407050402
Content-Type: multipart/related;
boundary="------------000507050606020207010709"


--------------000507050606020207010709
Content-Type: text/html; charset=ISO-8859-15
Content-Transfer-Encoding: quoted-printable




http-equiv=3D"Content-Type">


Hi,



das das explain analyze schnell ist und die echte aktion nicht
spricht für Probleme im Storage. Bei der Datenmenge und dem System
kann man CPU getrost ignorieren. Schau doch mal nach
Netzwerkproblemen. Ich würd ein Monitoring des Durchsatzes bei
anhaltendem IO Durchsatz machen.



Gruss

Thomas



Am 06.01.2011 06:40, schrieb Andreas Kretschmer:

>

Moin,



so, ich bin mit meinem Latein am Ende:



Im Log fand ich:

 LOG:  duration: 1021.310 ms  statement: delete fr=

om t_eingeloggt where personid =3D  148

So, nun mit psql und einem Explain analyse:

 explain analyse delete  from t_eingeloggt where p=

ersonid =3D  148;

                                                 QUERY PLAN

 ------------------------------------------------------------ -------------=

-----------------------------------

 Delete  (cost=3D0.00..4.39 rows=3D1 width=3D6) (actual time=3D0.069..0.0=

69 rows=3D0 loops=3D1)

   ->  Seq Scan on t_eingeloggt  (cost=3D0.00..4.39 rows=3D1 width=3D6=

) (actual time=3D0.066..0.066 rows=3D0 loops=3D1)

         Filter: (personid =3D 148)

 Total runtime: 0.091 ms

(4 rows)

(Tabelle enthält aktuell 192 records, besteht aus (int,

varchar(200),int) und hat einen Index auf personid.





Das ist ein Seq-Scan im Explain, der 0.1 ms braucht. Im Log taucht das

mit 10.000 facher Laufzeit auf. Der Server langweilt sich, da ist fast

keine LOAD, er hat 16 kerne und 24 GByte RAM. Storage via iSCSI, der

komplette DB-Cluster dürfte aber komplett im Shared-mem liegen.



Es lief kein Checkpoint bei der ersten Abfrage, der kam erst 2 Minuten

später und schrieb 1 Block.



Das ist kein Einzelfall, da sind etliche solcher unverständlichen

Laufzeiten im Log.





Sachdienliche Hinweise bitte an mich ...





Andreas

--

Thomas Markus



=========================3D=

=========================3D=

==

proventis GmbH | Zimmerstr. 79-81 | D-10117 Berlin |

Tel +49 (0)30 2936399-22 | Fax -50 | 
" href=3D"mailto:t.markus@proventis.net">t.markus@proventis.net

-----------------------------------------------------------------

Geschäftsführer: Norman Frischmuth | Sitz: Berlin

Handelsregister: AG Berlin-Charlottenburg, HR 82917

-----------------------------------------------------------------

Blue Ant-webbasiertes Projektmanagement - aktuelle Termine:


te/live/blueant/veranstaltungen.html">http://www.proventis.net/website/li=

ve/blueant/veranstaltungen.html

=========================3D=

=========================3D=

==